{
 "cells": [
  {
   "cell_type": "markdown",
   "id": "487cb63e",
   "metadata": {},
   "source": [
    "# Logging Example\n",
    "\n",
    "This notebook shows how to use the logging feature of `power-grid-model`.\n",
    "So far, there are two types of loggers available:\n",
    "\n",
    "| Type | What it captures |\n",
    "|------|------------------|\n",
    "| `LoggerType.info` | Timestamped debug messages. Useful for diagnosing various issues |\n",
    "| `LoggerType.benchmark` | Per calculation phase timing totals. Useful for performance analysis |\n",
    "\n",
    "\n",
    "> **Important**: loggers provide *hints*, not conclusions. Output is intended for advanced\n",
    "> users and may change between releases.\n",
    ">\n",
    "> Logging has a performance cost, which is why it is **opt-in**: loggers are not active\n",
    "> by default.\n",
    "\n",
    "## Example Network\n",
    "\n",
    "We reuse the 3-node network from the Power Flow Example:\n",
    "\n",
    "```\n",
    " -----------------------line_8---------------\n",
    " |                                          |\n",
    "node_1 ---line_3--- node_2 ----line_5---- node_6\n",
    " |                    |                     |\n",
    "source_10          sym_load_4           sym_load_7\n",
    "```"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "1202b29f",
   "metadata": {},
   "source": [
    "## Imports"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 1,
   "id": "e5b07c05",
   "metadata": {},
   "outputs": [],
   "source": [
    "from power_grid_model import (\n",
    "    AttributeType,\n",
    "    CalculationMethod,\n",
    "    ComponentType,\n",
    "    DatasetType,\n",
    "    LoadGenType,\n",
    "    Logger,\n",
    "    LoggerType,\n",
    "    PowerGridModel,\n",
    "    initialize_array,\n",
    ")"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "1368862a",
   "metadata": {},
   "source": [
    "## Build the Input Dataset"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 2,
   "id": "3fed3eaa",
   "metadata": {},
   "outputs": [],
   "source": [
    "node = initialize_array(DatasetType.input, ComponentType.node, 3)\n",
    "node[AttributeType.id] = [1, 2, 6]\n",
    "node[AttributeType.u_rated] = [10.5e3, 10.5e3, 10.5e3]\n",
    "\n",
    "line = initialize_array(DatasetType.input, ComponentType.line, 3)\n",
    "line[AttributeType.id] = [3, 5, 8]\n",
    "line[AttributeType.from_node] = [1, 2, 1]\n",
    "line[AttributeType.to_node] = [2, 6, 6]\n",
    "line[AttributeType.from_status] = [1, 1, 1]\n",
    "line[AttributeType.to_status] = [1, 1, 1]\n",
    "line[AttributeType.r1] = [0.25, 0.25, 0.25]\n",
    "line[AttributeType.x1] = [0.2, 0.2, 0.2]\n",
    "line[AttributeType.c1] = [10e-6, 10e-6, 10e-6]\n",
    "line[AttributeType.tan1] = [0.0, 0.0, 0.0]\n",
    "line[AttributeType.i_n] = [1000, 1000, 1000]\n",
    "\n",
    "sym_load = initialize_array(DatasetType.input, ComponentType.sym_load, 2)\n",
    "sym_load[AttributeType.id] = [4, 7]\n",
    "sym_load[AttributeType.node] = [2, 6]\n",
    "sym_load[AttributeType.status] = [1, 1]\n",
    "sym_load[AttributeType.type] = [LoadGenType.const_power, LoadGenType.const_power]\n",
    "sym_load[AttributeType.p_specified] = [20e6, 10e6]\n",
    "sym_load[AttributeType.q_specified] = [5e6, 2e6]\n",
    "\n",
    "source = initialize_array(DatasetType.input, ComponentType.source, 1)\n",
    "source[AttributeType.id] = [10]\n",
    "source[AttributeType.node] = [1]\n",
    "source[AttributeType.status] = [1]\n",
    "source[AttributeType.u_ref] = [1.0]\n",
    "\n",
    "input_data = {\n",
    "    ComponentType.node: node,\n",
    "    ComponentType.line: line,\n",
    "    ComponentType.sym_load: sym_load,\n",
    "    ComponentType.source: source,\n",
    "}\n",
    "\n",
    "model = PowerGridModel(input_data)"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "454914fc",
   "metadata": {},
   "source": [
    "## Text Logger\n",
    "\n",
    "A `LoggerType.info` logger captures diagnostic messages emitted\n",
    "during any stage of calculation. Each line is timestamped and tagged with the event code.\n",
    "\n",
    "**Usage:** use `Logger` as a context manager. On entry the logger is registered and active while on exit it is unregistered as renderend inactive. \n",
    "The output buffer is preserved after the `with` block and is accessible via `logger.output`."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 3,
   "id": "709151c2",
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "[2026-10-06 13:50:26.923Z] Tag:2000: 0.000658\n",
      "[2026-10-06 13:50:26.923Z] Tag:3100: 0.000001\n",
      "[2026-10-06 13:50:26.924Z] Tag:3211: 0.000872\n",
      "[2026-10-06 13:50:26.924Z] Tag:3233: 0.000007\n",
      "[2026-10-06 13:50:26.924Z] Tag:3241: 0.000001\n",
      "[2026-10-06 13:50:26.924Z] Tag:3251: 0.000083\n",
      "[2026-10-06 13:50:26.924Z] Tag:3233: 0.000000\n",
      "[2026-10-06 13:50:26.924Z] Tag:3241: 0.000001\n",
      "[2026-10-06 13:50:26.924Z] Tag:3251: 0.000000\n",
      "[2026-10-06 13:50:26.924Z] Tag:3233: 0.000000\n",
      "[2026-10-06 13:50:26.924Z] Tag:3241: 0.000000\n",
      "[2026-10-06 13:50:26.924Z] Tag:3251: 0.000000\n",
      "[2026-10-06 13:50:26.924Z] Tag:3290: 0.000003\n",
      "[2026-10-06 13:50:26.924Z] Tag:3200: 0.000990\n",
      "[2026-10-06 13:50:26.924Z] Tag:3253: 3\n",
      "[2026-10-06 13:50:26.924Z] Tag:3000: 0.001001\n",
      "[2026-10-06 13:50:26.924Z] Tag:4000: 0.000008\n",
      "[2026-10-06 13:50:26.924Z] Tag:100: 0.002803\n",
      "\n"
     ]
    }
   ],
   "source": [
    "with Logger(LoggerType.info) as info_logger:\n",
    "    output_data = model.calculate_power_flow(\n",
    "        symmetric=True,\n",
    "        calculation_method=CalculationMethod.newton_raphson,\n",
    "    )\n",
    "\n",
    "print(info_logger.output)"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "5646db62",
   "metadata": {},
   "source": [
    "## Benchmark Logger\n",
    "\n",
    "A `LoggerType.benchmark` logger records cumulative time spent in each\n",
    "calculation phase. The output is tab-separated with two columns: `EVENT_CODE` and\n",
    "`VALUE` (seconds).\n",
    "\n",
    "Unlike the info logger, the benchmark logger ignores string messages entirely. It\n",
    "only accumulates numeric (double) values of duration from internal timer events."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 4,
   "id": "426c48ac",
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "100\t4.3974e-05\n",
      "2000\t5.725e-06\n",
      "3000\t1.9704e-05\n",
      "3200\t1.7246e-05\n",
      "3211\t6.527e-06\n",
      "3233\t1.052e-06\n",
      "3241\t1.535e-06\n",
      "3251\t1.492e-06\n",
      "3253\t3\n",
      "3290\t4.35e-06\n",
      "4000\t1.1787e-05\n",
      "\n"
     ]
    }
   ],
   "source": [
    "with Logger(LoggerType.benchmark) as bench_logger:\n",
    "    output_data = model.calculate_power_flow(\n",
    "        symmetric=True,\n",
    "        calculation_method=CalculationMethod.newton_raphson,\n",
    "    )\n",
    "\n",
    "print(bench_logger.output)"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "17ba056c",
   "metadata": {},
   "source": [
    "## Multiple Simultaneous Loggers\n",
    "\n",
    "Multiple logger types can be combined in a single `with` statement. Each logger\n",
    "independently captures its own output."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 5,
   "id": "754b572d",
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "=== Info logger ===\n",
      "[2026-10-06 13:50:26.950Z] Tag:2000: 0.000008\n",
      "[2026-10-06 13:50:26.950Z] Tag:3211: 0.000006\n",
      "[2026-10-06 13:50:26.950Z] Tag:3233: 0.000001\n",
      "[2026-10-06 13:50:26.950Z] Tag:3241: 0.000001\n",
      "[2026-10-06 13:50:26.950Z] Tag:3251: 0.000001\n",
      "[2026-10-06 13:50:26.950Z] Tag:3233: 0.000000\n",
      "[2026-10-06 13:50:26.950Z] Tag:3241: 0.000000\n",
      "[2026-10-06 13:50:26.950Z] Tag:3251: 0.000000\n",
      "[2026-10-06 13:50:26.950Z] Tag:3233: 0.000000\n",
      "[2026-10-06 13:50:26.950Z] Tag:3241: 0.000000\n",
      "[2026-10-06 13:50:26.950Z] Tag:3251: 0.000000\n",
      "[2026-10-06 13:50:26.950Z] Tag:3290: 0.000008\n",
      "[2026-10-06 13:50:26.950Z] Tag:3200: 0.000035\n",
      "[2026-10-06 13:50:26.950Z] Tag:3253: 3\n",
      "[2026-10-06 13:50:26.950Z] Tag:3000: 0.000040\n",
      "[2026-10-06 13:50:26.950Z] Tag:4000: 0.000032\n",
      "[2026-10-06 13:50:26.950Z] Tag:100: 0.000140\n",
      "\n",
      "=== Benchmark logger ===\n",
      "100\t0.000139593\n",
      "2000\t7.813e-06\n",
      "3000\t3.9733e-05\n",
      "3200\t3.4965e-05\n",
      "3211\t5.763e-06\n",
      "3233\t1.175e-06\n",
      "3241\t1.548e-06\n",
      "3251\t1.45e-06\n",
      "3253\t3\n",
      "3290\t7.65e-06\n",
      "4000\t3.191e-05\n",
      "\n"
     ]
    }
   ],
   "source": [
    "with (\n",
    "    Logger(LoggerType.info) as info_logger2,\n",
    "    Logger(LoggerType.benchmark) as bench_logger2,\n",
    "):\n",
    "    output_data = model.calculate_power_flow(\n",
    "        symmetric=True,\n",
    "        calculation_method=CalculationMethod.newton_raphson,\n",
    "    )\n",
    "\n",
    "print(\"=== Info logger ===\")\n",
    "print(info_logger2.output)\n",
    "print(\"=== Benchmark logger ===\")\n",
    "print(bench_logger2.output)"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "5f8f356d",
   "metadata": {},
   "source": [
    "## Accumulation and Clearing Content\n",
    "\n",
    "Output accumulates across all calculations inside a single `with` block. Call\n",
    "`logger.clear_content()` inside the block to reset between calculations without\n",
    "unregistering."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 6,
   "id": "2d5130a7",
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "Combined output (11 lines):\n",
      "100\t0.000104808\n",
      "2000\t1.3031e-05\n",
      "3000\t4.802e-05\n",
      "3200\t4.2484e-05\n",
      "3211\t1.3951e-05\n",
      "3233\t3.622e-06\n",
      "3241\t5.827e-06\n",
      "3251\t3.873e-06\n",
      "3253\t3\n",
      "3290\t1e-05\n",
      "4000\t2.6465e-05\n",
      "\n"
     ]
    }
   ],
   "source": [
    "with Logger(LoggerType.benchmark) as acc_logger:\n",
    "    # Run four calculations while output accumulates inside the with block\n",
    "    for _ in range(4):\n",
    "        model.calculate_power_flow(symmetric=True)\n",
    "\n",
    "print(f\"Combined output ({acc_logger.output.count('\\n')} lines):\")\n",
    "print(acc_logger.output)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 7,
   "id": "d8a09276",
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "After first calc (11 lines)\n",
      "After clear_content: ''\n",
      "After second calc (11 lines):\n",
      "100\t4.4643e-05\n",
      "2000\t5.386e-06\n",
      "3000\t2.0341e-05\n",
      "3200\t1.8172e-05\n",
      "3211\t6.252e-06\n",
      "3233\t1.266e-06\n",
      "3241\t1.805e-06\n",
      "3251\t3.294e-06\n",
      "3253\t3\n",
      "3290\t3.861e-06\n",
      "4000\t1.0799e-05\n",
      "\n"
     ]
    }
   ],
   "source": [
    "# clear_content() resets the buffer without unregistering. This can be useful between runs\n",
    "with Logger(LoggerType.benchmark) as acc_logger:\n",
    "    model.calculate_power_flow(symmetric=True)\n",
    "    print(f\"After first calc ({acc_logger.output.count('\\n')} lines)\")\n",
    "\n",
    "    acc_logger.clear_content()\n",
    "    print(f\"After clear_content: {acc_logger.output!r}\")\n",
    "\n",
    "    model.calculate_power_flow(symmetric=True)\n",
    "\n",
    "print(f\"After second calc ({acc_logger.output.count('\\n')} lines):\")\n",
    "print(acc_logger.output)"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "7a081163",
   "metadata": {},
   "source": [
    "## Reuse Across Runs\n",
    "\n",
    "A `Logger` object can be re-entered across multiple `with` blocks. Each entry\n",
    "re-registers on the handle; each exit unregisters. Call `logger.clear_content()` between\n",
    "runs to start with a fresh buffer."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 8,
   "id": "73f98385",
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "Run 1: 11 lines, Run 2: 11 lines\n"
     ]
    }
   ],
   "source": [
    "reuse_logger = Logger(LoggerType.benchmark)\n",
    "\n",
    "with reuse_logger:\n",
    "    model.calculate_power_flow(symmetric=True)\n",
    "lines_run1 = reuse_logger.output.count(\"\\n\")\n",
    "\n",
    "reuse_logger.clear_content()\n",
    "\n",
    "with reuse_logger:\n",
    "    model.calculate_power_flow(symmetric=True)\n",
    "lines_run2 = reuse_logger.output.count(\"\\n\")\n",
    "\n",
    "print(f\"Run 1: {lines_run1} lines, Run 2: {lines_run2} lines\")"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "2e9ddc69",
   "metadata": {},
   "source": [
    "## Python Logging Integration\n",
    "\n",
    "Pass `python_logger=` to route output through the standard `logging` module.\n",
    "On `__exit__`, accumulated lines are flushed to `python_logger`. One log is recorded\n",
    "per line at the configured level and the internal buffer is cleared. No manual flush needed."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 9,
   "id": "0b63d096",
   "metadata": {},
   "outputs": [
    {
     "name": "stderr",
     "output_type": "stream",
     "text": [
      "INFO power_grid_model: Starting power flow calculation\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:2000: 0.000006\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3211: 0.000005\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3233: 0.000001\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3241: 0.000001\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3251: 0.000001\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3233: 0.000000\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3241: 0.000000\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3251: 0.000000\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3233: 0.000000\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3241: 0.000000\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3251: 0.000000\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3290: 0.000003\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3200: 0.000022\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3253: 3\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:3000: 0.000025\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:4000: 0.000010\n",
      "INFO power_grid_model: [2026-10-06 13:50:27.028Z] Tag:100: 0.000068\n"
     ]
    },
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "Buffer after exit: ''\n"
     ]
    }
   ],
   "source": [
    "import logging\n",
    "\n",
    "logging.basicConfig(level=logging.INFO, format=\"%(levelname)s %(name)s: %(message)s\")\n",
    "py_logger = logging.getLogger(\"power_grid_model\")\n",
    "\n",
    "with Logger(LoggerType.info, python_logger=py_logger) as py_log_logger:\n",
    "    py_logger.info(\"Starting power flow calculation\")\n",
    "    model.calculate_power_flow(\n",
    "        symmetric=True,\n",
    "        calculation_method=CalculationMethod.newton_raphson,\n",
    "    )\n",
    "\n",
    "# __exit__ flushed each line to py_logger automatically; buffer is now empty\n",
    "print(f\"Buffer after exit: {py_log_logger.output!r}\")"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "a80668b1",
   "metadata": {},
   "source": [
    "## Batch Calculations\n",
    "\n",
    "Loggers work seamlessly with batch calculations as well.\n",
    "It internally handles logging of multi-threaded calculations.\n",
    "In case of exceptions, correct output from loggers is not guaranteed."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": 10,
   "id": "aa8d5dfb",
   "metadata": {},
   "outputs": [
    {
     "name": "stdout",
     "output_type": "stream",
     "text": [
      "100\t0.00243333\n",
      "1100\t0.000238997\n",
      "1200\t0.000301152\n",
      "1220\t5.8282e-05\n",
      "1230\t8.8664e-05\n",
      "1231\t3.2429e-05\n",
      "2000\t2.1209e-05\n",
      "3000\t8.1919e-05\n",
      "3200\t7.464e-05\n",
      "3211\t2.2738e-05\n",
      "3233\t5.423e-06\n",
      "3241\t6.964e-06\n",
      "3251\t5.219e-06\n",
      "3253\t3\n",
      "3290\t2.7732e-05\n",
      "4000\t3.5953e-05\n",
      "\n"
     ]
    }
   ],
   "source": [
    "# Create a small batch update: vary the load in node_2 across 3 scenarios\n",
    "load_update = initialize_array(DatasetType.update, ComponentType.sym_load, (3, 3))\n",
    "load_update[AttributeType.id] = [4, 4, 4]\n",
    "load_update[AttributeType.p_specified] = [10e6, 20e6, 30e6]\n",
    "update_data = {ComponentType.sym_load: load_update}\n",
    "\n",
    "with Logger(LoggerType.benchmark) as batch_bench:\n",
    "    batch_output = model.calculate_power_flow(\n",
    "        update_data=update_data,\n",
    "        symmetric=True,\n",
    "        threading=0,  # parallel\n",
    "    )\n",
    "\n",
    "print(batch_bench.output)"
   ]
  },
  {
   "cell_type": "markdown",
   "id": "24a62b68",
   "metadata": {},
   "source": [
    "## Usage notes\n",
    "\n",
    "- **Do not** destroy (or let Python GC collect) a `Logger` inside an active `with` block. It \n",
    "   triggers a `ResourceWarning` and it is inefficient as the logger is not broadcasting but active internally. \n",
    "- **Do not** use the same logger from multiple user threads simultaneously. (The internal C-level\n",
    "  batch calculation threads are safe.)"
   ]
  }
 ],
 "metadata": {
  "kernelspec": {
   "display_name": "power-grid-model (3.14.7)",
   "language": "python",
   "name": "python3"
  },
  "language_info": {
   "codemirror_mode": {
    "name": "ipython",
    "version": 3
   },
   "file_extension": ".py",
   "mimetype": "text/x-python",
   "name": "python",
   "nbconvert_exporter": "python",
   "pygments_lexer": "ipython3",
   "version": "3.14.7"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 5
}